Skip to content

Reproduction of excessive tokio polling #284

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
wants to merge 2 commits into from
Closed

Reproduction of excessive tokio polling #284

wants to merge 2 commits into from

Conversation

k0nserv
Copy link
Member

@k0nserv k0nserv commented Sep 6, 2022 •
edited
Loading

⚠️ Don't merge, only intended for reproduction ⚠️

This change reproduces something weird that I ran across in tokio-console. For some reason the task

webrtc/webrtc/src/peer_connection/operation/mod.rs

Lines 54 to 56 in 5d05b88

tokio::spawn(async move {
Operations::start(l, ops_tx, ops_rx, close_rx).await;
});

seems to be polled extremely excessively by the Tokio runtime, despite it's waker not being woken.

image

Example screenshot after running for only a few minutes

Generally, the task only gets woken when an operation is queued, as one would expect.

To reproduce

  1. Build with RUSTFLAGS="--cfg tokio_unstable" cargo build --example reflect from the root
  2. Follow the instructions in the reflect README.md, but add the --debug argument when starting the example.
  3. Start tokio console with tokio-console

Environment

OS: macOS 12.5
Machine: Apple M1 Max Macbook Pro

@lookback-hugotunius
Reproduction of excessive tokio polling
5d05b88 
With this change the reflect example will demonstrate excessive polling
in the operations task despite not being woken.
@codecov
Copy link

codecov bot commented Sep 6, 2022 •
edited
Loading

Codecov Report

Merging #284 (4c5bbc3) into master (b43e05b) will decrease coverage by 0.06%.
The diff coverage is 0.00%.

@@            Coverage Diff             @@
##           master     #284      +/-   ##
==========================================
- Coverage   56.44%   56.38%   -0.07%     
==========================================
  Files         500      500              
  Lines       47316    47317       +1     
  Branches    12811    12804       -7     
==========================================
- Hits        26708    26679      -29     
- Misses       9992    10002      +10     
- Partials    10616    10636      +20
Impacted Files Coverage Δ
examples/examples/reflect/reflect.rs 0.00% <0.00%> (ø)
data/src/message/message_type.rs 75.00% <0.00%> (-5.00%) ⬇️
data/src/message/message_channel_open.rs 79.51% <0.00%> (-4.82%) ⬇️
rtcp/src/header.rs 63.93% <0.00%> (-3.28%) ⬇️
interceptor/src/stats/mod.rs 72.61% <0.00%> (-3.18%) ⬇️
rtp/src/header.rs 63.91% <0.00%> (-2.58%) ⬇️
media/src/track/constraint/non_numeric.rs 75.47% <0.00%> (-1.89%) ⬇️
rtcp/src/extended_report/dlrr.rs 55.88% <0.00%> (-1.48%) ⬇️
webrtc/src/peer_connection/peer_connection_test.rs 55.33% <0.00%> (-0.80%) ⬇️
sdp/src/description/session.rs 62.88% <0.00%> (-0.62%) ⬇️
... and 2 more

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

@k0nserv
Copy link
Member Author

k0nserv commented Sep 6, 2022

Added tracing of the futures involved in 4c5bbc3

As expected there's some polling at first, but then there's no more:

webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.573234 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.573257 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.579477 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.579533 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.583075 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.583123 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.594881 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.594937 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.598352 - Polled future Operations::start
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.598423 - Polled future Operation("_", "set_remote_description")
webrtc/src/peer_connection/mod.rs:936 [INFO] 17:28:15.608205 - peer connection state changed: connected
Peer Connection State has changed: connected
webrtc/src/peer_connection/operation/mod.rs:166 [INFO] 17:28:15.608504 - Done with operation Operation("_", "set_remote_description")
webrtc/src/peer_connection/operation/mod.rs:169 [INFO] 17:28:15.608569 - Operation loop spun
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.608584 - Polled future ops_rx.recv()
webrtc/src/peer_connection/operation/mod.rs:160 [INFO] 17:28:15.608602 - Started operation Operation("_", "set_local_description")
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.608615 - Polled future Operation("_", "set_local_description")
webrtc/src/peer_connection/operation/mod.rs:166 [INFO] 17:28:15.622875 - Done with operation Operation("_", "set_local_description")
webrtc/src/peer_connection/operation/mod.rs:169 [INFO] 17:28:15.622956 - Operation loop spun
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.622970 - Polled future ops_rx.recv()
webrtc/src/peer_connection/operation/mod.rs:40 [INFO] 17:28:15.622992 - Polled future close_rx.recv()

@k0nserv k0nserv mentioned this pull request Sep 7, 2022
Closed
@k0nserv
Copy link
Member Author

k0nserv commented Sep 20, 2022

Closing as there's no intent to merge this

@k0nserv k0nserv closed this Sep 20, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@k0nserv @lookback-hugotunius